**** dT 0.000
* top TEST ../../../../bin/varnishtest/tests/u00003.vtc starting
**** top extmacro def pkg_version=trunk
**** top extmacro def pkg_branch=trunk
**** top extmacro def pwd=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest
**** top extmacro def date(...)
**** top extmacro def string(...)
**** top extmacro def localhost=127.0.0.1
**** top extmacro def bad_backend=127.0.0.1:35265
**** top extmacro def listen_addr=127.0.0.1:0
**** top extmacro def bad_ip=192.0.2.255
**** top extmacro def topbuild=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub
**** top extmacro def topsrc=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/../..
**** top macro def testdir=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest/../../../../bin/varnishtest/tests
**** top macro def tmpdir=/home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284
**** top macro def vtcid=vtc.2613176.560dc284
** top === varnishtest "varnishncsa coverage"
* top VTEST varnishncsa coverage
** top === server s1 -repeat 2 {
** s1 Starting server
**** s1 macro def s1_addr=127.0.0.1
**** s1 macro def s1_port=36359
**** s1 macro def s1_sock=127.0.0.1:36359
* s1 Listen on 127.0.0.1:36359
** top === varnish v1 -vcl+backend {
** s1 Started on 127.0.0.1:36359 (2 iterations)
**** dT 0.007
** v1 Launch
*** v1 CMD: cd ${pwd} && exec varnishd -d -n /home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 43923' -P /home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284/v1/varnishd.pid -p vmod_path=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs
*** v1 CMD: cd /home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest && exec varnishd -d -n /home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 43923' -P /home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284/v1/varnishd.pid -p vmod_path=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs
*** v1 PID: 2613195
**** v1 macro def v1_pid=2613195
**** v1 macro def v1_name=/home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284/v1
**** dT 0.009
*** v1 debug|Info: Working directory not mounted on tmpfs partition
*** v1 debug|
**** dT 0.019
*** v1 debug|Debug: Version: varnish-trunk revision 4aa8d31f92283c154a8faeb7b56915015c0552f4
*** v1 debug|Debug: Platform: Linux,4.18.0-553.52.1.el8_10.s390x,s390x,-jlinux,-sdefault,-sdefault,-hcritbit
*** v1 debug|200 329
*** v1 debug|-----------------------------
*** v1 debug|Varnish Cache CLI 1.0
*** v1 debug|-----------------------------
*** v1 debug|Linux,4.18.0-553.52.1.el8_10.s390x,s390x,-jlinux,-sdefault,-sdefault,-hcritbit
*** v1 debug|varnish-trunk revision 4aa8d31f92283c154a8faeb7b56915015c0552f4
*** v1 debug|
*** v1 debug|Type 'help' for command list.
*** v1 debug|Type 'quit' to close CLI session.
*** v1 debug|Type 'start' to launch worker process.
*** v1 debug|
**** dT 0.124
**** v1 CLIPOLL 1 0x1 0x0 0x0
*** v1 CLI connection fd = 7
*** v1 CLI RX 107
**** v1 CLI RX|ambjysazuulroitgzrkcnrglyhhswlhx
**** v1 CLI RX|
**** v1 CLI RX|Authentication required.
**** v1 CLI TX|auth 9da7a77d2f1f2f5db9de413ccd60b31534952c39b9353d309f879c8ad58e9c05
**** dT 0.134
*** v1 CLI RX 200
**** v1 CLI RX|-----------------------------
**** v1 CLI RX|Varnish Cache CLI 1.0
**** v1 CLI RX|-----------------------------
**** v1 CLI RX|Linux,4.18.0-553.52.1.el8_10.s390x,s390x,-jlinux,-sdefault,-sdefault,-hcritbit
**** v1 CLI RX|varnish-trunk revision 4aa8d31f92283c154a8faeb7b56915015c0552f4
**** v1 CLI RX|
**** v1 CLI RX|Type 'help' for command list.
**** v1 CLI RX|Type 'quit' to close CLI session.
**** v1 CLI RX|Type 'start' to launch worker process.
**** v1 CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P
**** v1 CLI TX|vcl 4.1;
**** v1 CLI TX|backend s1 { .host = "127.0.0.1"; .port = "36359"; }
**** v1 CLI TX|
**** v1 CLI TX|
**** v1 CLI TX|\timport std;
**** v1 CLI TX|
**** v1 CLI TX|\tsub vcl_recv {
**** v1 CLI TX|\t\tif (req.url == "/2") {
**** v1 CLI TX|\t\t\treturn (pipe);
**** v1 CLI TX|\t\t}
**** v1 CLI TX|\t\treturn (hash);
**** v1 CLI TX|\t}
**** v1 CLI TX|
**** v1 CLI TX|\tsub vcl_miss {
**** v1 CLI TX|\t\tstd.log("quux:quuz");
**** v1 CLI TX|\t}
**** v1 CLI TX|
**** v1 CLI TX|\tsub vcl_hit {
**** v1 CLI TX|\t\treturn (synth(404));
**** v1 CLI TX|\t}
**** v1 CLI TX|
**** v1 CLI TX|%XJEIFLH|)Xspa8P
**** dT 0.238
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.342
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.442
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.555
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.660
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.664
*** v1 CLI RX 200
**** v1 CLI RX|VCL compiled.
**** v1 CLI TX|vcl.use vcl1
*** v1 CLI RX 200
**** v1 CLI RX|VCL 'vcl1' now active
** v1 Start
**** v1 CLI TX|start
**** dT 0.721
*** v1 debug|Debug: Child (2613208) Started
**** dT 0.762
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.840
*** v1 debug|Child launched OK
**** dT 0.856
*** v1 CLI RX 200
*** v1 wait-running
**** v1 CLI TX|status
*** v1 CLI RX 200
**** v1 CLI RX|Child in state running
**** v1 CLI TX|debug.listen_address
*** v1 debug|Info: Child (2613208) said Child starts
**** dT 0.867
**** v1 vsl| 0 CLI - Rd vcl.load "vcl1" vcl_vcl1.1747796510.298546/vgc.so 1auto
**** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl1.1747796510.298546/vgc.so" as "vcl1"
**** v1 vsl| 0 CLI - Rd vcl.use "vcl1"
**** v1 vsl| 0 CLI - Wr 200 0
**** v1 vsl| 0 CLI - Rd start
**** v1 vsl| 0 Debug - sockopt: Setting SO_LINGER for a0=127.0.0.1:43791
**** v1 vsl| 0 Debug - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:43791
**** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:43791
**** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:43791
**** v1 vsl| 0 Debug - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:43791
**** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:43791
**** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:43791
**** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:43791
**** v1 vsl| 0 CLI - Wr 200 0
**** dT 0.913
*** v1 CLI RX 200
**** v1 CLI RX|a0 127.0.0.1 43791
**** v1 CLI TX|debug.xid 1000
**** dT 0.967
**** v1 vsl| 0 CLI - Rd debug.listen_address
**** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 43791
**** v1 vsl| 0 CLI - Rd debug.xid 1000
**** v1 vsl| 0 CLI - Wr 200 19 XID is 1000 chunk 1
**** dT 0.971
*** v1 CLI RX 200
**** v1 CLI RX|XID is 1000 chunk 1
**** v1 CLI TX|debug.listen_address
**** dT 1.031
*** v1 CLI RX 200
**** v1 CLI RX|a0 127.0.0.1 43791
** v1 Listen on 127.0.0.1 43791
**** v1 macro def v1_addr=127.0.0.1
**** v1 macro def v1_port=43791
**** v1 macro def v1_sock=127.0.0.1:43791
**** v1 macro def v1_a0_addr=127.0.0.1
**** v1 macro def v1_a0_port=43791
**** v1 macro def v1_a0_sock=127.0.0.1:43791
** top === shell {
**** top shell_cmd|set -e ;exec 2>&1 ;
**** top shell_cmd|\tvarnishncsa -n /home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284/v1 -D -P /home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284/ncsa.pid \
**** top shell_cmd|\t\t-w /home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284/ncsa.log -R 100/s
**** dT 1.068
**** v1 vsl| 0 CLI - Rd debug.listen_address
**** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 43791
**** dT 1.131
**** top shell_status = 0x0000
** top === process p1 -winsz 25 200 {varnishncsa -n ${v1_name}} -start
**** dT 1.155
**** p1 TIOCWINSZ -1 Bad file descriptor
**** p1 CMD: varnishncsa -n /home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284/v1
*** p1 PID: 2613263
**** dT 1.161
**** p1 macro def p1_pid=2613263
**** p1 macro def p1_dir=/home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284/p1
**** p1 macro def p1_out=/home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284/p1/term
**** p1 macro def p1_err=/home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284/p1/stderr
** top === delay 1
*** top delaying 1 second(s)
**** dT 2.162
** top === client c1 {
** c1 Starting client
** c1 Waiting for client
** c1 Started on 127.0.0.1:43791 (1 iterations)
*** c1 Connect to 127.0.0.1:43791
*** c1 connected fd 21 from 127.0.0.1 59058 to 127.0.0.1:43791
** c1 === txreq -nouseragent -url /1?foo=bar -hdr "authorization: basi...
**** c1 txreq|GET /1?foo=bar HTTP/1.1\r
**** c1 txreq|authorization: basic dXNlcjpwYXNz\r
**** c1 txreq|Host: 127.0.0.1\r
**** c1 txreq|\r
** c1 === rxresp
**** dT 2.171
*** s1 accepted fd 5 127.0.0.1 50676
** s1 === rxreq
**** s1 rxhdr|GET /1?foo=bar HTTP/1.1\r
**** s1 rxhdr|authorization: basic dXNlcjpwYXNz\r
**** s1 rxhdr|Host: 127.0.0.1\r
**** s1 rxhdr|X-Forwarded-For: 127.0.0.1\r
**** s1 rxhdr|Via: 1.1 v1 (Varnish/trunk)\r
**** s1 rxhdr|Accept-Encoding: gzip\r
**** s1 rxhdr|X-Varnish: 1002\r
**** s1 rxhdr|\r
**** s1 rxhdrlen = 176
**** s1 http[ 0] |GET
**** s1 http[ 1] |/1?foo=bar
**** s1 http[ 2] |HTTP/1.1
**** s1 http[ 3] |authorization: basic dXNlcjpwYXNz
**** s1 http[ 4] |Host: 127.0.0.1
**** s1 http[ 5] |X-Forwarded-For: 127.0.0.1
**** s1 http[ 6] |Via: 1.1 v1 (Varnish/trunk)
**** s1 http[ 7] |Accept-Encoding: gzip
**** s1 http[ 8] |X-Varnish: 1002
**** s1 bodylen = 0
** s1 === txresp -bodylen 100
**** s1 txresp|HTTP/1.1 200 OK\r
**** s1 txresp|Date: Wed, 21 May 2025 03:01:52 GMT\r
**** s1 txresp|Server: s1\r
**** s1 txresp|Content-Length: 100\r
**** s1 txresp|\r
**** s1 txresp|!"#$%&'()*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_
**** s1 txresp|"#$%&'()*+,-./0123456789:;<=>?@ABCD
*** s1 shutting fd 5 (server run)
**** dT 2.177
**** c1 rxhdr|HTTP/1.1 200 OK\r
**** c1 rxhdr|Date: Wed, 21 May 2025 03:01:52 GMT\r
**** c1 rxhdr|Server: s1\r
**** c1 rxhdr|Content-Length: 100\r
**** c1 rxhdr|X-Varnish: 1001\r
**** c1 rxhdr|Age: 0\r
**** c1 rxhdr|Via: 1.1 v1 (Varnish/trunk)\r
**** c1 rxhdr|Accept-Ranges: bytes\r
**** c1 rxhdr|Connection: keep-alive\r
**** c1 rxhdr|\r
**** c1 rxhdrlen = 189
**** c1 http[ 0] |HTTP/1.1
**** c1 http[ 1] |200
**** c1 http[ 2] |OK
**** c1 http[ 3] |Date: Wed, 21 May 2025 03:01:52 GMT
**** c1 http[ 4] |Server: s1
**** c1 http[ 5] |Content-Length: 100
**** c1 http[ 6] |X-Varnish: 1001
**** c1 http[ 7] |Age: 0
**** c1 http[ 8] |Via: 1.1 v1 (Varnish/trunk)
**** c1 http[ 9] |Accept-Ranges: bytes
**** c1 http[10] |Connection: keep-alive
**** c1 c-l|!"#$%&'()*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_
**** c1 c-l|"#$%&'()*+,-./0123456789:;<=>?@ABCD
**** c1 bodylen = 100
** c1 === txreq -nouseragent -url /1?foo=bar -hdr "baz: qux"
**** c1 txreq|GET /1?foo=bar HTTP/1.1\r
**** c1 txreq|baz: qux\r
**** c1 txreq|Host: 127.0.0.1\r
**** c1 txreq|\r
** c1 === rxresp
**** dT 2.188
**** c1 rxhdr|HTTP/1.1 404 Not Found\r
**** c1 rxhdr|Date: Wed, 21 May 2025 03:01:52 GMT\r
**** c1 rxhdr|Server: Varnish\r
**** c1 rxhdr|X-Varnish: 1003\r
**** c1 rxhdr|Content-Type: text/html; charset=utf-8\r
**** c1 rxhdr|Retry-After: 5\r
**** c1 rxhdr|Content-Length: 248\r
**** c1 rxhdr|Connection: keep-alive\r
**** c1 rxhdr|\r
**** c1 rxhdrlen = 198
**** c1 http[ 0] |HTTP/1.1
**** c1 http[ 1] |404
**** c1 http[ 2] |Not Found
**** c1 http[ 3] |Date: Wed, 21 May 2025 03:01:52 GMT
**** c1 http[ 4] |Server: Varnish
**** c1 http[ 5] |X-Varnish: 1003
**** c1 http[ 6] |Content-Type: text/html; charset=utf-8
**** c1 http[ 7] |Retry-After: 5
**** c1 http[ 8] |Content-Length: 248
**** c1 http[ 9] |Connection: keep-alive
**** c1 c-l|
**** c1 c-l|
**** c1 c-l|
**** c1 c-l| 404 Not Found
**** c1 c-l|
**** c1 c-l|
**** c1 c-l| Error 404 Not Found
**** c1 c-l| Not Found
**** c1 c-l| Guru Meditation:
**** c1 c-l| XID: 1003
**** c1 c-l|
**** c1 c-l| Varnish cache server
**** c1 c-l|
**** c1 c-l|
**** c1 bodylen = 248
*** c1 closing fd 21
** c1 Ending
** top === delay 1
*** top delaying 1 second(s)
**** dT 2.195
**** v1 vsl| 1000 Begin c sess 0 HTTP/1
**** v1 vsl| 1000 SessOpen c 127.0.0.1 59058 a0 127.0.0.1 43791 1747796512.333670 22
**** v1 vsl| 1000 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:43791
**** v1 vsl| 1000 Debug c sockopt: SO_KEEPALIVE may be inherited for a0=127.0.0.1:43791
**** v1 vsl| 1000 Debug c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:43791
**** v1 vsl| 1000 Debug c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:43791
**** v1 vsl| 1000 Debug c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:43791
**** v1 vsl| 1000 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:43791
**** v1 vsl| 1000 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:43791
**** v1 vsl| 1000 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:43791
**** v1 vsl| 1000 Link c req 1001 rxreq
**** v1 vsl| 1002 Begin b bereq 1001 fetch
**** v1 vsl| 1002 VCL_use b vcl1
**** v1 vsl| 1002 Timestamp b Start: 1747796512.334694 0.000000 0.000000
**** v1 vsl| 1002 BereqMethod b GET
**** v1 vsl| 1002 BereqURL b /1?foo=bar
**** v1 vsl| 1002 BereqProtocol b HTTP/1.1
**** v1 vsl| 1002 BereqHeader b authorization: basic dXNlcjpwYXNz
**** v1 vsl| 1002 BereqHeader b Host: 127.0.0.1
**** v1 vsl| 1002 BereqHeader b X-Forwarded-For: 127.0.0.1
**** v1 vsl| 1002 BereqHeader b Via: 1.1 v1 (Varnish/trunk)
**** v1 vsl| 1002 BereqHeader b Accept-Encoding: gzip
**** v1 vsl| 1002 BereqHeader b X-Varnish: 1002
**** v1 vsl| 1002 VCL_call b BACKEND_FETCH
**** v1 vsl| 1002 VCL_return b fetch
**** v1 vsl| 1002 Timestamp b Fetch: 1747796512.334721 0.000026 0.000026
**** v1 vsl| 1002 Timestamp b Connected: 1747796512.334803 0.000108 0.000081
**** v1 vsl| 1002 BackendOpen b 25 s1 127.0.0.1 36359 127.0.0.1 50676 connect
**** v1 vsl| 1002 Timestamp b Bereq: 1747796512.334834 0.000139 0.000031
**** v1 vsl| 1002 BerespProtocol b HTTP/1.1
**** v1 vsl| 1002 BerespStatus b 200
**** v1 vsl| 1002 BerespReason b OK
**** v1 vsl| 1002 BerespHeader b Date: Wed, 21 May 2025 03:01:52 GMT
**** v1 vsl| 1002 BerespHeader b Server: s1
**** v1 vsl| 1002 BerespHeader b Content-Length: 100
**** v1 vsl| 1002 Timestamp b Beresp: 1747796512.336132 0.001437 0.001297
**** v1 vsl| 1002 TTL b RFC 120 10 0 1747796512 1747796512 1747796512 0 0 cacheable
**** v1 vsl| 1002 VCL_call b BACKEND_RESPONSE
**** v1 vsl| 1002 VCL_return b deliver
**** v1 vsl| 1002 Debug b Missing content-range header or unknown range unit
**** v1 vsl| 1002 Timestamp b Process: 1747796512.336171 0.001476 0.000038
**** v1 vsl| 1002 Filters b
**** v1 vsl| 1002 Storage b malloc s0
**** v1 vsl| 1002 Fetch_Body b 3 length stream
**** v1 vsl| 1002 BackendClose b 25 s1 recycle
**** v1 vsl| 1002 Timestamp b BerespBody: 1747796512.346592 0.011897 0.010421
**** v1 vsl| 1002 Length b 100
**** v1 vsl| 1002 BereqAcct b 176 0 176 89 100 189
**** v1 vsl| 1002 End b
**** v1 vsl| 1001 Begin c req 1000 rxreq
**** v1 vsl| 1001 Timestamp c Start: 1747796512.333724 0.000000 0.000000
**** v1 vsl| 1001 Timestamp c Req: 1747796512.333724 0.000000 0.000000
**** v1 vsl| 1001 VCL_use c vcl1
**** v1 vsl| 1001 ReqStart c 127.0.0.1 59058 a0
**** v1 vsl| 1001 ReqMethod c GET
**** v1 vsl| 1001 ReqURL c /1?foo=bar
**** v1 vsl| 1001 ReqProtocol c HTTP/1.1
**** v1 vsl| 1001 ReqHeader c authorization: basic dXNlcjpwYXNz
**** v1 vsl| 1001 ReqHeader c Host: 127.0.0.1
**** v1 vsl| 1001 ReqHeader c X-Forwarded-For: 127.0.0.1
**** v1 vsl| 1001 ReqHeader c Via: 1.1 v1 (Varnish/trunk)
**** v1 vsl| 1001 VCL_call c RECV
**** v1 vsl| 1001 VCL_return c hash
**** v1 vsl| 1001 VCL_call c HASH
**** v1 vsl| 1001 VCL_return c lookup
**** v1 vsl| 1001 VCL_call c MISS
**** v1 vsl| 1001 VCL_Log c quux:quuz
**** v1 vsl| 1001 VCL_return c fetch
**** v1 vsl| 1001 Link c bereq 1002 fetch
**** v1 vsl| 1001 Timestamp c Fetch: 1747796512.338854 0.005130 0.005130
**** v1 vsl| 1001 RespProtocol c HTTP/1.1
**** v1 vsl| 1001 RespStatus c 200
**** v1 vsl| 1001 RespReason c OK
**** v1 vsl| 1001 RespHeader c Date: Wed, 21 May 2025 03:01:52 GMT
**** v1 vsl| 1001 RespHeader c Server: s1
**** v1 vsl| 1001 RespHeader c Content-Length: 100
**** v1 vsl| 1001 RespHeader c X-Varnish: 1001
**** v1 vsl| 1001 RespHeader c Age: 0
**** v1 vsl| 1001 RespHeader c Via: 1.1 v1 (Varnish/trunk)
**** v1 vsl| 1001 RespHeader c Accept-Ranges: bytes
**** v1 vsl| 1001 VCL_call c DELIVER
**** v1 vsl| 1001 VCL_return c deliver
**** v1 vsl| 1001 Timestamp c Process: 1747796512.338877 0.005153 0.000023
**** v1 vsl| 1001 Filters c
**** v1 vsl| 1001 RespHeader c Connection: keep-alive
**** v1 vsl| 1001 Timestamp c Resp: 1747796512.349236 0.015512 0.010359
**** v1 vsl| 1001 ReqAcct c 79 0 79 189 100 289
**** v1 vsl| 1001 End c
**** v1 vsl| 1000 Link c req 1003 rxreq
**** v1 vsl| 1003 Begin c req 1000 rxreq
**** v1 vsl| 1003 Timestamp c Start: 1747796512.349286 0.000000 0.000000
**** v1 vsl| 1003 Timestamp c Req: 1747796512.349286 0.000000 0.000000
**** v1 vsl| 1003 VCL_use c vcl1
**** v1 vsl| 1003 ReqStart c 127.0.0.1 59058 a0
**** v1 vsl| 1003 ReqMethod c GET
**** v1 vsl| 1003 ReqURL c /1?foo=bar
**** v1 vsl| 1003 ReqProtocol c HTTP/1.1
**** v1 vsl| 1003 ReqHeader c baz: qux
**** v1 vsl| 1003 ReqHeader c Host: 127.0.0.1
**** v1 vsl| 1003 ReqHeader c X-Forwarded-For: 127.0.0.1
**** v1 vsl| 1003 ReqHeader c Via: 1.1 v1 (Varnish/trunk)
**** v1 vsl| 1003 VCL_call c RECV
**** v1 vsl| 1003 VCL_return c hash
**** v1 vsl| 1003 VCL_call c HASH
**** v1 vsl| 1003 VCL_return c lookup
**** v1 vsl| 1003 Hit c 1002 119.986846 10.000000 0.000000
**** v1 vsl| 1003 VCL_call c HIT
**** v1 vsl| 1003 VCL_return c synth
**** v1 vsl| 1003 RespProtocol c HTTP/1.1
**** v1 vsl| 1003 RespStatus c 404
**** v1 vsl| 1003 RespReason c Not Found
**** v1 vsl| 1003 RespHeader c Date: Wed, 21 May 2025 03:01:52 GMT
**** v1 vsl| 1003 RespHeader c Server: Varnish
**** v1 vsl| 1003 RespHeader c X-Varnish: 1003
**** v1 vsl| 1003 VCL_call c SYNTH
**** v1 vsl| 1003 RespHeader c Content-Type: text/html; charset=utf-8
**** v1 vsl| 1003 RespHeader c Retry-After: 5
**** v1 vsl| 1003 VCL_return c deliver
**** v1 vsl| 1003 Timestamp c Process: 1747796512.349343 0.000056 0.000056
**** v1 vsl| 1003 RespHeader c Content-Length: 248
**** v1 vsl| 1003 Storage c malloc Transient
**** v1 vsl| 1003 Filters c
**** v1 vsl| 1003 RespHeader c Connection: keep-alive
**** v1 vsl| 1003 Timestamp c Resp: 1747796512.349362 0.000076 0.000019
**** v1 vsl| 1003 ReqAcct c 54 0 54 198 248 446
**** v1 vsl| 1003 End c
**** v1 vsl| 1000 SessClose c REM_CLOSE 0.021
**** v1 vsl| 1000 End c
**** dT 3.188
** top === shell "mv ${tmpdir}/ncsa.log ${tmpdir}/ncsa.old.log"
**** top shell_cmd|set -e ;exec 2>&1 ; mv /home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284/ncsa.log /home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284/ncsa.old.log
**** dT 3.201
**** top shell_status = 0x0000
** top === shell "kill -HUP `cat ${tmpdir}/ncsa.pid`"
**** top shell_cmd|set -e ;exec 2>&1 ; kill -HUP `cat /home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284/ncsa.pid`
**** dT 3.314
**** top shell_status = 0x0000
** top === client c2 {
** c2 Starting client
** c2 Waiting for client
**** dT 3.315
** c2 Started on 127.0.0.1:43791 (1 iterations)
*** c2 Connect to 127.0.0.1:43791
*** c2 connected fd 21 from 127.0.0.1 41156 to 127.0.0.1:43791
** c2 === txreq -nouseragent -url /2
**** c2 txreq|GET /2 HTTP/1.1\r
**** c2 txreq|Host: 127.0.0.1\r
**** c2 txreq|\r
** c2 === rxresp
**** dT 3.320
**** v1 vsl| 1004 Begin c sess 0 HTTP/1
**** v1 vsl| 1004 SessOpen c 127.0.0.1 41156 a0 127.0.0.1 43791 1747796513.483881 23
**** v1 vsl| 1004 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:43791
**** v1 vsl| 1004 Debug c sockopt: SO_KEEPALIVE may be inherited for a0=127.0.0.1:43791
**** v1 vsl| 1004 Debug c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:43791
**** v1 vsl| 1004 Debug c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:43791
**** v1 vsl| 1004 Debug c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:43791
**** v1 vsl| 1004 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:43791
**** v1 vsl| 1004 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:43791
**** v1 vsl| 1004 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:43791
**** v1 vsl| 1004 Link c req 1005 rxreq
**** dT 3.321
*** s1 accepted fd 5 127.0.0.1 53426
** s1 === rxreq
**** s1 rxhdr|GET /2 HTTP/1.1\r
**** s1 rxhdr|Host: 127.0.0.1\r
**** s1 rxhdr|X-Forwarded-For: 127.0.0.1\r
**** s1 rxhdr|Via: 1.1 v1 (Varnish/trunk)\r
**** s1 rxhdr|X-Varnish: 1005\r
**** s1 rxhdr|Connection: close\r
**** s1 rxhdr|\r
**** s1 rxhdrlen = 129
**** s1 http[ 0] |GET
**** s1 http[ 1] |/2
**** s1 http[ 2] |HTTP/1.1
**** s1 http[ 3] |Host: 127.0.0.1
**** s1 http[ 4] |X-Forwarded-For: 127.0.0.1
**** s1 http[ 5] |Via: 1.1 v1 (Varnish/trunk)
**** s1 http[ 6] |X-Varnish: 1005
**** s1 http[ 7] |Connection: close
**** s1 bodylen = 0
** s1 === txresp -bodylen 100
**** s1 txresp|HTTP/1.1 200 OK\r
**** s1 txresp|Date: Wed, 21 May 2025 03:01:53 GMT\r
**** s1 txresp|Server: s1\r
**** s1 txresp|Content-Length: 100\r
**** s1 txresp|\r
**** s1 txresp|!"#$%&'()*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_
**** s1 txresp|"#$%&'()*+,-./0123456789:;<=>?@ABCD
*** s1 shutting fd 5 (server run)
** s1 Ending
**** dT 3.325
**** c2 rxhdr|HTTP/1.1 200 OK\r
**** c2 rxhdr|Date: Wed, 21 May 2025 03:01:53 GMT\r
**** c2 rxhdr|Server: s1\r
**** c2 rxhdr|Content-Length: 100\r
**** c2 rxhdr|\r
**** c2 rxhdrlen = 89
**** c2 http[ 0] |HTTP/1.1
**** c2 http[ 1] |200
**** c2 http[ 2] |OK
**** c2 http[ 3] |Date: Wed, 21 May 2025 03:01:53 GMT
**** c2 http[ 4] |Server: s1
**** c2 http[ 5] |Content-Length: 100
**** c2 c-l|!"#$%&'()*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_
**** c2 c-l|"#$%&'()*+,-./0123456789:;<=>?@ABCD
**** c2 bodylen = 100
*** c2 closing fd 21
** c2 Ending
**** dT 3.326
** top === delay 1
*** top delaying 1 second(s)
**** dT 3.423
**** v1 vsl| 1006 Begin b bereq 1005 pipe
**** v1 vsl| 1006 Timestamp b Start: 1747796513.483986 0.000000 0.000000
**** v1 vsl| 1006 BereqMethod b GET
**** v1 vsl| 1006 BereqURL b /2
**** v1 vsl| 1006 BereqProtocol b HTTP/1.1
**** v1 vsl| 1006 BereqHeader b Host: 127.0.0.1
**** v1 vsl| 1006 BereqHeader b X-Forwarded-For: 127.0.0.1
**** v1 vsl| 1006 BereqHeader b Via: 1.1 v1 (Varnish/trunk)
**** v1 vsl| 1006 BereqHeader b X-Varnish: 1005
**** v1 vsl| 1006 BereqHeader b Connection: close
**** v1 vsl| 1006 Timestamp b Process: 1747796513.483993 0.000006 0.000006
**** v1 vsl| 1006 Timestamp b Connected: 1747796513.484026 0.000039 0.000032
**** v1 vsl| 1006 BackendOpen b 25 s1 127.0.0.1 36359 127.0.0.1 53426 connect
**** v1 vsl| 1006 Timestamp b Bereq: 1747796513.484047 0.000060 0.000020
**** v1 vsl| 1006 BackendClose b 25 s1 close TX_PIPE
**** v1 vsl| 1006 BereqAcct b 0 0 0 0 0 0
**** v1 vsl| 1006 End b
**** v1 vsl| 1005 Begin c req 1004 rxreq
**** v1 vsl| 1005 Timestamp c Start: 1747796513.483930 0.000000 0.000000
**** v1 vsl| 1005 Timestamp c Req: 1747796513.483930 0.000000 0.000000
**** v1 vsl| 1005 VCL_use c vcl1
**** v1 vsl| 1005 ReqStart c 127.0.0.1 41156 a0
**** v1 vsl| 1005 ReqMethod c GET
**** v1 vsl| 1005 ReqURL c /2
**** v1 vsl| 1005 ReqProtocol c HTTP/1.1
**** v1 vsl| 1005 ReqHeader c Host: 127.0.0.1
**** v1 vsl| 1005 ReqHeader c X-Forwarded-For: 127.0.0.1
**** v1 vsl| 1005 ReqHeader c Via: 1.1 v1 (Varnish/trunk)
**** v1 vsl| 1005 VCL_call c RECV
**** v1 vsl| 1005 VCL_return c pipe
**** v1 vsl| 1005 VCL_call c HASH
**** v1 vsl| 1005 VCL_return c lookup
**** v1 vsl| 1005 Link c bereq 1006 pipe
**** v1 vsl| 1005 VCL_call c PIPE
**** v1 vsl| 1005 VCL_return c pipe
**** v1 vsl| 1005 Timestamp c Process: 1747796513.483993 0.000063 0.000063
**** v1 vsl| 1005 Timestamp c Pipe: 1747796513.484047 0.000117 0.000054
**** v1 vsl| 1005 Timestamp c PipeSess: 1747796513.489189 0.005258 0.005141
**** v1 vsl| 1005 PipeAcct c 36 129 0 189
**** v1 vsl| 1005 End c
**** v1 vsl| 1004 SessClose c TX_PIPE 0.005
**** v1 vsl| 1004 End c
**** dT 3.933
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796514 1.0
**** dT 4.326
** top === shell "kill `cat ${tmpdir}/ncsa.pid`"
**** top shell_cmd|set -e ;exec 2>&1 ; kill `cat /home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284/ncsa.pid`
**** dT 4.339
**** top shell_status = 0x0000
** top === shell -match {${localhost} - user \[../.../20[1-9][0-9]:..:....
**** top shell_cmd|set -e ;exec 2>&1 ; cat /home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284/ncsa.old.log
**** dT 4.344
**** top shell_out|127.0.0.1 - user [20/May/2025:23:01:52 -0400] "GET http://127.0.0.1/1?foo=bar HTTP/1.1" 200 100 "-" "-"
**** top shell_out|127.0.0.1 - - [20/May/2025:23:01:52 -0400] "GET http://127.0.0.1/1?foo=bar HTTP/1.1" 404 248 "-" "-"
**** top shell_status = 0x0000
**** top shell_match succeeded
** top === shell "grep -q /2 ${tmpdir}/ncsa.log"
**** top shell_cmd|set -e ;exec 2>&1 ; grep -q /2 /home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284/ncsa.log
**** dT 4.350
**** top shell_status = 0x0000
** top === shell -match "Usage: .*varnishncsa " \
**** top shell_cmd|set -e ;exec 2>&1 ; varnishncsa -h
**** dT 4.388
**** top shell_out|Usage: /home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishncsa/.libs/lt-varnishncsa
**** top shell_out|
**** top shell_out|Options:
**** top shell_out| [-a] Append to file
**** top shell_out| [-b] Backend mode
**** top shell_out| [-c] Client mode
**** top shell_out| [-C] Caseless regular expressions
**** top shell_out| [-d] Process old log entries and exit
**** top shell_out| [-D] Daemonize
**** top shell_out| [-E] Show ESI requests
**** top shell_out| [-F ] Set output format
**** top shell_out| [-f ] Read output format from file
**** top shell_out| [-g ] Grouping mode (default: vxid)
**** top shell_out| [-h] Usage help
**** top shell_out| [-j] Make output JSON-compatible
**** top shell_out| [-k ] Limit transactions
**** top shell_out| [-L ] Incomplete transaction limit
**** top shell_out| [-n ] varnish working directory
**** top shell_out| [-P ] PID file
**** top shell_out| [-Q ] VSL query file
**** top shell_out| [-q ] VSL query
**** top shell_out| [-r ] Binary file input
**** top shell_out| [-R ] Output rate limit
**** top shell_out| [-t ] VSM connection timeout
**** top shell_out| [-V] Version
**** top shell_out| [-w ] Output filename
**** top shell_status = 0x0000
**** top shell_match succeeded
** top === shell -expect "Copyright (c) 2006 Verdens Gang AS" \
**** top shell_cmd|set -e ;exec 2>&1 ; varnishncsa -V
**** dT 4.456
**** top shell_out|/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishncsa/.libs/lt-varnishncsa (varnish-trunk revision 4aa8d31f92283c154a8faeb7b56915015c0552f4)
**** top shell_out|Copyright (c) 2006 Verdens Gang AS
**** top shell_out|Copyright (c) 2006-2025 Varnish Software
**** top shell_out|Copyright 2010-2025 UPLEX - Nils Goroll Systemoptimierung
**** top shell_status = 0x0000
**** top shell_expect found
** top === shell -err -expect "Missing -w option" \
**** top shell_cmd|set -e ;exec 2>&1 ; varnishncsa -D
**** dT 4.518
**** top shell_out|Missing -w option
**** top shell_status = 0x0001
**** top shell_expect found
** top === shell -err -expect "Daemon cannot write to stdout" \
**** top shell_cmd|set -e ;exec 2>&1 ; varnishlog -D -w -
**** dT 4.568
**** top shell_out|Daemon cannot write to stdout
**** top shell_status = 0x0001
**** top shell_expect found
** top === shell -err -expect "Unknown format specifier at: %{foo}A" \
**** top shell_cmd|set -e ;exec 2>&1 ; varnishncsa -F "%{foo}A"
**** dT 4.638
**** top shell_out|Unknown format specifier at: %{foo}A
**** top shell_status = 0x0001
**** top shell_expect found
** top === shell -err -expect "Unknown format specifier at: %A" \
**** top shell_cmd|set -e ;exec 2>&1 ; varnishncsa -F "%A"
**** dT 4.688
**** top shell_out|Unknown format specifier at: %A
**** top shell_status = 0x0001
**** top shell_expect found
** top === shell -err -expect "Unmatched bracket at: %{foo" \
**** top shell_cmd|set -e ;exec 2>&1 ; varnishncsa -F %{foo
**** dT 4.749
**** top shell_out|Unmatched bracket at: %{foo
**** top shell_status = 0x0001
**** top shell_expect found
** top === shell -err -expect "Unknown formatting extension: foo" \
**** top shell_cmd|set -e ;exec 2>&1 ; varnishncsa -F "%{foo}x"
**** dT 4.795
**** top shell_out|Unknown formatting extension: foo
**** top shell_status = 0x0001
**** top shell_expect found
** top === shell -err -expect "Missing tag in VSL:" \
**** top shell_cmd|set -e ;exec 2>&1 ; varnishncsa -F "%{VSL:}x"
**** dT 4.954
**** top shell_out|Missing tag in VSL:
**** top shell_status = 0x0001
**** top shell_expect found
** top === shell -err -expect "Unknown log tag: nonexistent" \
**** top shell_cmd|set -e ;exec 2>&1 ; varnishncsa -F "%{VSL:nonexistent}x"
**** dT 5.025
**** top shell_out|Unknown log tag: nonexistent
**** top shell_status = 0x0001
**** top shell_expect found
** top === shell -err -expect "Tag not unique: Req" \
**** top shell_cmd|set -e ;exec 2>&1 ; varnishncsa -F "%{VSL:Req}x"
**** dT 5.092
**** top shell_out|Tag not unique: Req
**** top shell_status = 0x0001
**** top shell_expect found
** top === shell -err -expect "Unknown log tag: Begin[" \
**** top shell_cmd|set -e ;exec 2>&1 ; varnishncsa -F "%{VSL:Begin[}x"
**** dT 5.157
**** top shell_out|Unknown log tag: Begin[
**** top shell_status = 0x0001
**** top shell_expect found
** top === shell -err -expect "Syntax error: VSL:Begin]" \
**** top shell_cmd|set -e ;exec 2>&1 ; varnishncsa -F "%{VSL:Begin]}x"
**** dT 5.217
**** top shell_out|Syntax error: VSL:Begin]
**** top shell_status = 0x0001
**** top shell_expect found
** top === shell -err -expect "Unknown log tag: Begin[a" \
**** top shell_cmd|set -e ;exec 2>&1 ; varnishncsa -F "%{VSL:Begin[a}x"
**** dT 5.283
**** top shell_out|Unknown log tag: Begin[a
**** top shell_status = 0x0001
**** top shell_expect found
**** dT 5.284
** top === shell -err -expect "Syntax error: VSL:Begin[a]" \
**** top shell_cmd|set -e ;exec 2>&1 ; varnishncsa -F "%{VSL:Begin[a]}x"
**** dT 5.352
**** top shell_out|Syntax error: VSL:Begin[a]
**** top shell_status = 0x0001
**** top shell_expect found
** top === shell -err -match {Syntax error. (?#
**** top shell_cmd|set -e ;exec 2>&1 ; varnishncsa -F "%{VSL:Begin[0]}x"
**** dT 5.450
**** top shell_out|Syntax error. Field specifier must be between 1 and 255: Begin[0]
**** top shell_status = 0x0001
**** top shell_match succeeded
** top === shell -err -match {Syntax error. (?#
**** top shell_cmd|set -e ;exec 2>&1 ; varnishncsa -F "%{VSL:Begin[999999999999]}x"
**** dT 5.516
**** top shell_out|Syntax error. Field specifier must be between 1 and 255: Begin[999999999999]
**** top shell_status = 0x0001
**** top shell_match succeeded
** top === shell -err -expect "Can't open format file (No such file or ...
**** top shell_cmd|set -e ;exec 2>&1 ; varnishncsa -f /nonexistent/file
**** dT 5.642
**** top shell_out|Can't open format file (No such file or directory)
**** top shell_status = 0x0001
**** top shell_expect found
** top === shell -err -expect "Empty format file" \
**** top shell_cmd|set -e ;exec 2>&1 ; varnishncsa -f /dev/null
**** dT 5.708
**** top shell_out|Empty format file
**** top shell_status = 0x0001
**** top shell_expect found
** top === shell -err -expect "Invalid grouping mode: session" \
**** top shell_cmd|set -e ;exec 2>&1 ; varnishncsa -g session
**** dT 5.755
**** top shell_out|Invalid grouping mode: session
**** top shell_status = 0x0001
**** top shell_expect found
** top === shell -err -expect "Can't open output file (No such file or ...
**** top shell_cmd|set -e ;exec 2>&1 ; varnishncsa -w /nonexistent/file
**** dT 5.821
**** top shell_out|Can't open output file (No such file or directory)
**** top shell_status = 0x0001
**** top shell_expect found
** top === shell -err -match "Usage: .*varnishncsa " \
**** top shell_cmd|set -e ;exec 2>&1 ; varnishncsa extra
**** dT 5.924
**** top shell_out|Usage: /home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishncsa/.libs/lt-varnishncsa
**** top shell_out|
**** top shell_out|Options:
**** top shell_out| [-a] Append to file
**** top shell_out| [-b] Backend mode
**** top shell_out| [-c] Client mode
**** top shell_out| [-C] Caseless regular expressions
**** top shell_out| [-d] Process old log entries and exit
**** top shell_out| [-D] Daemonize
**** top shell_out| [-E] Show ESI requests
**** top shell_out| [-F ] Set output format
**** top shell_out| [-f ] Read output format from file
**** top shell_out| [-g ] Grouping mode (default: vxid)
**** top shell_out| [-h] Usage help
**** top shell_out| [-j] Make output JSON-compatible
**** top shell_out| [-k ] Limit transactions
**** top shell_out| [-L ] Incomplete transaction limit
**** top shell_out| [-n ] varnish working directory
**** top shell_out| [-P ] PID file
**** top shell_out| [-Q ] VSL query file
**** top shell_out| [-q ] VSL query
**** top shell_out| [-r ] Binary file input
**** top shell_out| [-R ] Output rate limit
**** top shell_out| [-t ] VSM connection timeout
**** top shell_out| [-V] Version
**** top shell_out| [-w ] Output filename
**** top shell_status = 0x0001
**** top shell_match succeeded
** top === shell -match {^${localhost} 100
**** top shell_cmd|set -e ;exec 2>&1 ; varnishncsa -n /home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284/v1 -b -d -F "%{Host}i %b"
**** dT 6.071
**** top shell_out|127.0.0.1 100
**** top shell_out|127.0.0.1 0
**** top shell_status = 0x0000
**** top shell_match succeeded
** top === shell -match {^${localhost} 100
**** top shell_cmd|set -e ;exec 2>&1 ; VARNISH_DEFAULT_N="/home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284/v1" varnishncsa -b -d -F "%{Host}i %b"
**** dT 6.229
**** top shell_out|127.0.0.1 100
**** top shell_out|127.0.0.1 0
**** top shell_status = 0x0000
**** top shell_match succeeded
** top === shell -match {^${localhost} 100
**** top shell_cmd|set -e ;exec 2>&1 ; varnishncsa -n /home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284/v1 -c -d -F "%{Host}i %b"
**** dT 6.387
**** top shell_out|127.0.0.1 100
**** top shell_out|127.0.0.1 248
**** top shell_out|127.0.0.1 -
**** top shell_status = 0x0000
**** top shell_match succeeded
** top === shell {echo "%b %D %H %h %I %{baz}i %l %m %{Age}o %O %q %s %...
**** top shell_cmd|set -e ;exec 2>&1 ; echo "%b %D %H %h %I %{baz}i %l %m %{Age}o %O %q %s %t %{%Y}t \
**** top shell_cmd|%T %U %u" > /home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284/format
**** dT 6.389
**** top shell_status = 0x0000
** top === shell -match {^100 \d+ HTTP/1.1 (?:\d+.\d+.\d+.\d+|[a-f0-9:]...
**** top shell_cmd|set -e ;exec 2>&1 ; varnishncsa -n /home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284/v1 -d -f /home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284/format
**** dT 6.554
**** top shell_out|100 15511 HTTP/1.1 127.0.0.1 79 - - GET 0 289 ?foo=bar 200 [20/May/2025:23:01:52 -0400] 2025 0 /1 user
**** top shell_out|248 75 HTTP/1.1 127.0.0.1 54 qux - GET - 446 ?foo=bar 404 [20/May/2025:23:01:52 -0400] 2025 0 /1 -
**** top shell_out|- 5258 HTTP/1.1 127.0.0.1 0 - - GET - 189 - [20/May/2025:23:01:53 -0400] 2025 0 /2 -
**** top shell_status = 0x0000
**** top shell_match succeeded
** top === shell -match {^\d+.\d{6} miss miss c 1001 quuz
**** top shell_cmd|set -e ;exec 2>&1 ; varnishncsa -n /home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284/v1 -d -F "%{Varnish:time_firstbyte}x \
**** top shell_cmd|%{Varnish:hitmiss}x %{Varnish:handling}x %{Varnish:side}x \
**** top shell_cmd|%{Varnish:vxid}x %{VCL_Log:quux}x"
**** dT 6.714
**** top shell_out|0.005153 miss miss c 1001 quuz
**** top shell_out|0.000056 miss synth c 1003
**** top shell_out|0.000063 miss pipe c 1005
**** top shell_status = 0x0000
**** top shell_match succeeded
** top === shell -match {^req (\d+) rxreq \1 \d{10}\.\d{6} (\d+\.\d{6})...
**** top shell_cmd|set -e ;exec 2>&1 ; varnishncsa -n /home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284/v1 -d -F "%{VSL:Begin}x \
**** top shell_cmd|%{VSL:Begin[2]}x %{VSL:Timestamp:Resp}x \
**** top shell_cmd|%{VSL:Timestamp:Resp[2]}x %{VSL:Timestamp:foo}x %{VSL:ReqURL[2]}x"
**** dT 6.868
**** top shell_out|req 1000 rxreq 1000 1747796512.349236 0.015512 0.010359 0.015512 - -
**** top shell_out|req 1000 rxreq 1000 1747796512.349362 0.000076 0.000019 0.000076 - -
**** top shell_out|req 1004 rxreq 1004 - - - -
**** top shell_status = 0x0000
**** top shell_match succeeded
** top === shell -match {^\{\d{4}-\d{2}-\d{2}\}T\{\d{2}:\d{2}:\d{2}\} \...
**** top shell_cmd|set -e ;exec 2>&1 ; varnishncsa -n /home/linux1/VT/_vtest_tmp/vtc.2613176.560dc284/v1 -d -F "%{{%F}T{%T}}t %{{{%FT%T}}}t \
**** top shell_cmd|%{s}T %{ms}T %{us}T %{sec}t %{msec}t %{usec}t %{msec_frac}t %{usec_frac}t \
**** top shell_cmd|%{usecx}t %{msecy}t"
**** dT 6.903
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796517 1.0
**** dT 7.038
**** top shell_out|{2025-05-20}T{23:01:52} {{2025-05-20T23:01:52}} 0 15 15511 1747796512 1747796512333 1747796512333724 333 333724 usecx msecy
**** top shell_out|{2025-05-20}T{23:01:52} {{2025-05-20T23:01:52}} 0 0 75 1747796512 1747796512349 1747796512349286 349 349286 usecx msecy
**** top shell_out|{2025-05-20}T{23:01:53} {{2025-05-20T23:01:53}} 0 5 5258 1747796513 1747796513483 1747796513483930 483 483930 usecx msecy
**** top shell_status = 0x0000
**** top shell_match succeeded
** top === process p1 -stop -screen-dump
**** p1 Sent signal 15
**** p1 stdout read -1
**** p1 stderr read 0
** p1 WAIT4 pid=2613263 status=0x0000 (user 0.006391 sys 0.377745)
**** p1 macro undef p1_pid
**** dT 8.039
*** p1 screen|127.0.0.1 - - [20/May/2025:23:01:53 -0400] "GET http://127.0.0.1/2 HTTP/1.1" - - "-" "-"
*** p1 screen|
*** p1 screen|
*** p1 screen|
*** p1 screen|
*** p1 screen|
*** p1 screen|
*** p1 screen|
*** p1 screen|
*** p1 screen|
*** p1 screen|
*** p1 screen|
*** p1 screen|
*** p1 screen|
*** p1 screen|
*** p1 screen|
*** p1 screen|
*** p1 screen|
*** p1 screen|
*** p1 screen|
*** p1 screen|
*** p1 screen|
*** p1 screen|
*** p1 screen|
*** p1 screen|
*** p1 Cursor at line 2 column 1
** top === process p1 -expect-text 1 0 {/1?foo=bar HTTP/1.1" 200 100 "-...
**** dT 9.870
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796520 1.0
**** dT 12.922
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796523 1.0
**** dT 15.854
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796526 1.0
**** dT 18.902
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796529 1.0
**** dT 21.952
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796532 1.0
**** dT 24.902
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796535 1.0
**** dT 27.952
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796538 1.0
**** dT 30.890
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796541 1.0
**** dT 33.930
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796544 1.0
**** dT 36.898
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796547 1.0
**** dT 39.937
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796550 1.0
**** dT 42.874
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796553 1.0
**** dT 45.922
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796556 1.0
**** dT 48.875
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796559 1.0
**** dT 51.909
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796562 1.0
**** dT 54.954
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796565 1.0
**** dT 57.901
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796568 1.0
**** dT 60.955
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796571 1.0
**** dT 63.898
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796574 1.0
**** dT 66.964
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796577 1.0
**** dT 69.910
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796580 1.0
**** dT 72.944
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796583 1.0
**** dT 76.013
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796586 1.0
**** dT 78.968
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796589 1.0
**** dT 82.010
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796592 1.0
**** dT 84.955
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796595 1.0
**** dT 88.020
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796598 1.0
**** dT 90.964
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796601 1.0
**** dT 94.002
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796604 1.0
**** dT 96.953
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796607 1.0
**** dT 100.024
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796610 1.0
**** dT 102.965
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796613 1.0
**** dT 106.018
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796616 1.0
**** dT 108.973
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796619 1.0
**** dT 112.040
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796622 1.0
**** dT 114.995
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796625 1.0
**** dT 118.048
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796628 1.0
**** dT 120.996
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796631 1.0
**** dT 124.037
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796634 1.0
**** dT 127.083
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796637 1.0
**** dT 130.015
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796640 1.0
**** dT 133.048
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796643 1.0
**** dT 136.002
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796646 1.0
**** dT 139.061
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796649 1.0
**** dT 142.097
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796652 1.0
**** dT 145.037
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796655 1.0
**** dT 148.096
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796658 1.0
**** dT 151.032
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796661 1.0
**** dT 154.077
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796664 1.0
**** dT 157.117
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796667 1.0
**** dT 160.053
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796670 1.0
**** dT 163.090
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796673 1.0
**** dT 166.126
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796676 1.0
**** dT 169.055
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796679 1.0
**** dT 172.079
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796682 1.0
**** dT 175.110
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796685 1.0
**** dT 178.061
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1747796688 1.0
# top TEST ../../../../bin/varnishtest/tests/u00003.vtc TIMED OUT (kill -9)
# top TEST ../../../../bin/varnishtest/tests/u00003.vtc FAILED (180.106) signal=9
FAIL tests/u00003.vtc (exit status: 2)